iT邦幫忙

2025 iThome 鐵人賽

DAY 8
0
Software Development

重啟挑戰:老派軟體工程師的測試修練系列 第 8

Day 08:測試輸出與記錄 - xUnit ITestOutputHelper 與 ILogger

  • 分享至 

  • xImage
  •  

前言

前面我們已經學會了單元測試的核心技能:

  • Day 01 建立測試金字塔的觀念基礎
  • Day 02 打造第一個測試專案
  • Day 03 深入 AAA 模式與 xUnit 框架
  • Day 04 掌握各種斷言技巧
  • Day 05 探索進階斷言與集合驗證
  • Day 06 學會程式碼覆蓋率的實務應用
  • Day 07 掌握依賴替代與 NSubstitute 的使用

現在我們面臨一個實務問題:當測試失敗時,如何快速定位問題?當系統行為需要分析時,如何收集必要資訊?測試不只是驗證功能正確性,也是建立可觀測性與診斷能力的重要環節。今天我們要學習測試輸出與記錄的實用技術。

本日學習目標

  • 理解測試輸出與記錄在診斷中的重要性
  • 掌握 xUnit ITestOutputHelper 的正確使用方式與生命週期管理
  • 學會設計結構化的測試輸出格式,提升可讀性
  • 正確使用 ILogger 進行測試中的記錄驗證與行為測試
  • 理解 ILogger 擴充方法的測試挑戰與解決方案
  • 建立測試診斷工具與快速問題定位的技巧

測試輸出需求分析

為何需要測試輸出與記錄?

在複雜的軟體系統中,測試輸出與記錄扮演重要角色:

1. 診斷需求

  • 測試失敗時快速定位問題根源
  • 理解測試執行過程中的狀態變化
  • 驗證系統行為是否符合預期

2. 除錯支援

  • 提供測試執行的詳細軌跡
  • 記錄重要變數與狀態資訊
  • 協助開發者理解複雜的業務邏輯流程

3. 可觀測性

  • 建立系統行為的可見性
  • 監控效能指標與資源使用
  • 追蹤業務流程的執行情況

ITestOutputHelper 實用應用

基礎使用與正確注入

為什麼需要使用 ITestOutputHelper?

在傳統的程式開發中,我們習慣使用 Console.WriteLine() 來輸出除錯資訊。但在 xUnit 測試環境中,這種方式有幾個問題:

  1. 輸出不會顯示在測試結果中Console.WriteLine() 的輸出不會整合到測試報告裡
  2. 並行執行時的混亂:當多個測試並行執行時,console 輸出會混在一起
  3. 測試失敗時缺乏上下文:無法在測試失敗時看到相關的診斷資訊

ITestOutputHelper 的解決方案

xUnit 提供了 ITestOutputHelper 介面來解決這些問題:

  • 測試隔離:每個測試方法都有獨立的輸出通道
  • 整合報告:輸出會出現在測試結果和測試報告中
  • 上下文保持:測試失敗時可以看到相關的診斷資訊
  • 並行安全:不同測試的輸出不會互相干擾

正確的注入方式

當我們需要在測試執行過程中輸出訊息時,應該透過建構式注入 ITestOutputHelper

實用範例

以下範例展示如何在複雜的業務邏輯測試中使用 ITestOutputHelper 來追蹤測試執行過程:

using AwesomeAssertions;
using Xunit;
using Xunit.Abstractions;

public class ProductServiceTests
{
    private readonly ITestOutputHelper _output;

    public ProductServiceTests(ITestOutputHelper testOutputHelper)
    {
        this._output = testOutputHelper;
    }

    [Fact]
    public void CalculateDiscount_VIP客戶購買高價商品_應回傳20%折扣()
    {
        // Arrange
        var customer = new Customer { Type = CustomerType.VIP, PurchaseHistory = 15000 };
        var product = new Product { Price = 1000, Category = "Electronics" };
        
        _output.WriteLine($"Testing VIP customer: {customer.Type}, History: {customer.PurchaseHistory}");
        _output.WriteLine($"Product: {product.Category}, Price: {product.Price}");

        var service = new ProductService();

        // Act
        var discount = service.CalculateDiscount(customer, product);

        // Assert
        _output.WriteLine($"Calculated discount: {discount}%");
        discount.Should().Be(20); // VIP(10%) + 高價商品(5%) + 購買歷史(5%) = 20%
    }
}

輸出結果示例

當測試執行時,這些輸出會出現在測試結果中:

Testing VIP customer: VIP, History: 15000
Product: Electronics, Price: 1000
Calculated discount: 20%

這種輸出在測試失敗時特別有用,能夠快速了解測試執行時的狀態和數據。

生命週期管理與注意事項

正確的生命週期管理

  • ITestOutputHelper 的實例與每個測試方法綁定
  • 每個測試方法執行時都會取得新的實例
  • 不可在靜態方法或跨測試方法間共用

常見誤區

using Xunit.Abstractions;

// X 錯誤:嘗試靜態存取
public static class TestHelper
{
    private static ITestOutputHelper _output; // 錯誤:靜態存取
    
    public static void LogInfo(string message)
    {
        _output.WriteLine(message); // 這會失敗
    }
}

// O 正確:透過依賴注入
public class TestHelper
{
    private readonly ITestOutputHelper _output;
    
    public TestHelper(ITestOutputHelper output)
    {
        _output = output;
    }
    
    public void LogInfo(string message)
    {
        _output.WriteLine(message);
    }
}

結構化輸出格式設計

為了提高測試輸出的可讀性,建議採用結構化的輸出格式:

using System;
using AwesomeAssertions;
using Xunit;
using Xunit.Abstractions;

public class StructuredOutputTests
{
    private readonly ITestOutputHelper _output;

    public StructuredOutputTests(ITestOutputHelper testOutputHelper)
    {
        this._output = testOutputHelper;
    }

    [Fact]
    public void ProcessOrder_包含多項商品_應計算正確總額()
    {
        // Arrange
        LogSection("=== 測試設置 ===");
        var order = new Order
        {
            Items = new[]
            {
                new OrderItem { ProductName = "筆記型電腦", Price = 30000, Quantity = 1 },
                new OrderItem { ProductName = "滑鼠", Price = 800, Quantity = 2 },
                new OrderItem { ProductName = "鍵盤", Price = 1500, Quantity = 1 }
            }
        };

        LogOrderDetails(order);

        // Act
        LogSection("=== 執行測試 ===");
        var startTime = DateTime.Now;
        var result = processor.ProcessOrder(order);
        var endTime = DateTime.Now;
        
        LogPerformance(startTime, endTime);

        // Assert
        LogSection("=== 驗證結果 ===");
        _output.WriteLine($"計算總額: {result.TotalAmount:C}");
        _output.WriteLine($"預期總額: {32300:C}");
        
        result.TotalAmount.Should().Be(32300);
        LogSection("=== 測試完成 ===");
    }

    private void LogSection(string title)
    {
        _output.WriteLine(title);
    }

    private void LogOrderDetails(Order order)
    {
        _output.WriteLine("訂單明細:");
        foreach (var item in order.Items)
        {
            _output.WriteLine($"  - {item.ProductName}: {item.Price:C} x {item.Quantity}");
        }
    }

    private void LogPerformance(DateTime start, DateTime end)
    {
        var duration = end - start;
        _output.WriteLine($"執行時間: {duration.TotalMilliseconds:F2} ms");
    }
}

效能測試中的時間點記錄

在效能測試中,時間點記錄是重要的診斷資訊:

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading.Tasks;
using AwesomeAssertions;
using Xunit;

[Fact]
public async Task ProcessLargeDataSet_處理一萬筆資料_應在五秒內完成()
{
    // Arrange
    var dataSet = GenerateLargeDataSet(10000);
    var processor = new DataProcessor();
    
    var stopwatch = Stopwatch.StartNew();
    var checkpoints = new List<(string Stage, TimeSpan Elapsed)>();

    // Act & Monitor
    _output.WriteLine("開始處理大型資料集...");
    
    stopwatch.Restart();
    await processor.LoadData(dataSet);
    checkpoints.Add(("資料載入", stopwatch.Elapsed));
    _output.WriteLine($"資料載入完成: {stopwatch.Elapsed.TotalMilliseconds:F2} ms");

    await processor.ValidateData();
    checkpoints.Add(("資料驗證", stopwatch.Elapsed));
    _output.WriteLine($"資料驗證完成: {stopwatch.Elapsed.TotalMilliseconds:F2} ms");

    var result = await processor.ProcessData();
    checkpoints.Add(("資料處理", stopwatch.Elapsed));
    _output.WriteLine($"資料處理完成: {stopwatch.Elapsed.TotalMilliseconds:F2} ms");

    stopwatch.Stop();

    // Assert & Report
    _output.WriteLine("\n=== 效能報告 ===");
    foreach (var (stage, elapsed) in checkpoints)
    {
        _output.WriteLine($"{stage}: {elapsed.TotalMilliseconds:F2} ms");
    }
    
    var totalTime = stopwatch.Elapsed;
    _output.WriteLine($"總執行時間: {totalTime.TotalMilliseconds:F2} ms");
    
    // 驗證效能要求(例如:5秒內完成)
    totalTime.Should().BeLessThan(TimeSpan.FromSeconds(5));
}

測試執行輸出結果:

=== 測試設置 ===
訂單明細:
  - 筆記型電腦: NT$30,000.00 x 1
  - 滑鼠: NT$800.00 x 2
  - 鍵盤: NT$1,500.00 x 1
=== 執行測試 ===
執行時間: 1.86 ms
=== 驗證結果 ===
計算總額: NT$33,100.00
預期總額: NT$33,100.00
=== 測試完成 ===

ILogger 測試策略

從自訂記錄介面到標準 ILogger

在實際專案中,我們通常使用 Microsoft.Extensions.Logging.ILogger 而非自訂的記錄介面。讓我們透過電商訂單處理的例子來學習如何進行測試:

using Microsoft.Extensions.Logging;

public class OrderProcessingService
{
    private readonly ILogger<OrderProcessingService> _logger;
    private readonly IInventoryService _inventoryService;
    private readonly IPaymentService _paymentService;

    public OrderProcessingService(
        ILogger<OrderProcessingService> logger,
        IInventoryService inventoryService, 
        IPaymentService paymentService)
    {
        _logger = logger;
        _inventoryService = inventoryService;
        _paymentService = paymentService;
    }

    public OrderResult ProcessOrder(Order order)
    {
        _logger.LogInformation("開始處理訂單 {OrderId} for customer {CustomerId}", order.Id, order.CustomerId);

        // 檢查庫存
        var stockAvailable = _inventoryService.CheckStock(order.ProductId, order.Quantity);
        if (!stockAvailable)
        {
            _logger.LogWarning("商品 {ProductId} 庫存不足,數量需求:{RequestedQuantity}", 
                order.ProductId, order.Quantity);
            return new OrderResult { Success = false, ErrorMessage = "庫存不足" };
        }

        // 處理付款
        var paymentResult = _paymentService.ProcessPayment(order.TotalAmount);
        if (!paymentResult.Success)
        {
            _logger.LogError("訂單 {OrderId} 付款失敗:{ErrorMessage}", 
                order.Id, paymentResult.ErrorMessage);
            return new OrderResult { Success = false, ErrorMessage = "付款失敗" };
        }

        _logger.LogInformation("訂單 {OrderId} 處理完成,金額:{Amount}", order.Id, order.TotalAmount);
        return new OrderResult { Success = true, OrderId = order.Id };
    }
}

記錄層級驗證技巧

挑戰:擴充方法的測試問題

ILogger.LogError() 是擴充方法,NSubstitute 無法直接攔截,需要攔截底層的 Log<TState> 方法:

using System;
using Microsoft.Extensions.Logging;
using NSubstitute;
using Xunit;

// X 這種方式會失敗
[Fact]
public void ProcessOrder_付款失敗_應記錄錯誤_錯誤示範()
{
    // Arrange
    var logger = Substitute.For<ILogger<OrderProcessingService>>();
    // ...setup...

    // Act
    var result = sut.ProcessOrder(order);

    // Assert - 這會拋出 RedundantArgumentMatcherException
    logger.Received().LogError(Arg.Is<string>(x => x.Contains("付款失敗")));
}

// O 正確的方式:攔截底層方法
[Fact]
public void ProcessOrder_付款失敗_應記錄錯誤_正確示範()
{
    // Arrange
    var logger = Substitute.For<ILogger<OrderProcessingService>>();
    // ...setup...

    // Act
    var result = sut.ProcessOrder(order);

    // Assert
    logger.Received().Log(
        LogLevel.Error,
        Arg.Any<EventId>(),
        Arg.Any<object>(),
        Arg.Any<Exception>(),
        Arg.Any<Func<object, Exception?, string>>());
}

避免對記錄框架的直接相依

為了簡化測試並避免複雜的 Log<TState> 驗證,我們可以創建抽象層:

using System;
using Microsoft.Extensions.Logging;

public abstract class AbstractLogger<T> : ILogger<T>
{
    public IDisposable BeginScope<TState>(TState state)
        => throw new NotImplementedException();

    public bool IsEnabled(LogLevel logLevel) => true;

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, 
        Exception exception, Func<TState, Exception, string> formatter)
        => Log(logLevel, exception, formatter(state, exception));

    public abstract void Log(LogLevel logLevel, Exception ex, string information);
}

使用抽象 Logger 簡化測試:

using AwesomeAssertions;
using NSubstitute;
using NSubstitute.Extensions;
using Xunit;

public class OrderProcessingServiceTests
{
    private readonly AbstractLogger<OrderProcessingService> _logger;
    private readonly IInventoryService _inventoryService;
    private readonly IPaymentService _paymentService;

    public OrderProcessingServiceTests()
    {
        _logger = Substitute.For<AbstractLogger<OrderProcessingService>>();
        _inventoryService = Substitute.For<IInventoryService>();
        _paymentService = Substitute.For<IPaymentService>();
    }

    [Fact]
    public void ProcessOrder_正常處理_應記錄開始與完成訊息()
    {
        // Arrange
        var order = new Order 
        { 
            Id = "ORD001", 
            CustomerId = "CUST001", 
            ProductId = "PROD001",
            Quantity = 2,
            TotalAmount = 1000 
        };
        
        _inventoryService.CheckStock(order.ProductId, order.Quantity).Returns(true);
        _paymentService.ProcessPayment(order.TotalAmount)
            .Returns(new PaymentResult { Success = true });
        
        var sut = new OrderProcessingService(_logger, _inventoryService, _paymentService);

        // Act
        var result = sut.ProcessOrder(order);

        // Assert
        result.Success.Should().BeTrue();
        
        // 驗證記錄了開始處理訊息
        _logger.Received().Log(
            logLevel: LogLevel.Information, 
            ex: null, 
            information: Arg.Is<string>(msg => msg.Contains("開始處理訂單") && msg.Contains("ORD001")));
            
        // 驗證記錄了完成訊息
        _logger.Received().Log(
            logLevel: LogLevel.Information, 
            ex: null, 
            information: Arg.Is<string>(msg => msg.Contains("處理完成") && msg.Contains("1000")));
    }

    [Fact]
    public void ProcessOrder_庫存不足_應記錄警告訊息()
    {
        // Arrange
        var order = new Order 
        { 
            Id = "ORD002", 
            ProductId = "PROD002",
            Quantity = 5 
        };
        
        _inventoryService.CheckStock(order.ProductId, order.Quantity).Returns(false);
        
        var sut = new OrderProcessingService(_logger, _inventoryService, _paymentService);

        // Act
        var result = sut.ProcessOrder(order);

        // Assert
        result.Success.Should().BeFalse();
        result.ErrorMessage.Should().Be("庫存不足");
        
        _logger.Received().Log(
            logLevel: LogLevel.Warning, 
            ex: null, 
            information: Arg.Is<string>(msg => msg.Contains("庫存不足") && msg.Contains("PROD002")));
    }

    [Fact]
    public void ProcessOrder_付款失敗_應記錄錯誤訊息()
    {
        // Arrange
        var order = new Order 
        { 
            Id = "ORD003", 
            ProductId = "PROD003",
            Quantity = 1,
            TotalAmount = 500 
        };
        
        _inventoryService.CheckStock(order.ProductId, order.Quantity).Returns(true);
        _paymentService.ProcessPayment(order.TotalAmount)
            .Returns(new PaymentResult { Success = false, ErrorMessage = "信用卡驗證失敗" });
        
        var sut = new OrderProcessingService(_logger, _inventoryService, _paymentService);

        // Act
        var result = sut.ProcessOrder(order);

        // Assert
        result.Success.Should().BeFalse();
        result.ErrorMessage.Should().Be("付款失敗");
        
        _logger.Received().Log(
            logLevel: LogLevel.Error, 
            ex: null, 
            information: Arg.Is<string>(msg => msg.Contains("付款失敗") && msg.Contains("ORD003")));
    }
}

// 支援類別定義
public class Order
{
    public string Id { get; set; }
    public string CustomerId { get; set; }
    public string ProductId { get; set; }
    public int Quantity { get; set; }
    public decimal TotalAmount { get; set; }
}

public class OrderResult
{
    public bool Success { get; set; }
    public string OrderId { get; set; }
    public string ErrorMessage { get; set; }
}

public interface IInventoryService
{
    bool CheckStock(string productId, int quantity);
}

public interface IPaymentService
{
    PaymentResult ProcessPayment(decimal amount);
}

public class PaymentResult
{
    public bool Success { get; set; }
    public string ErrorMessage { get; set; }
}

實務整合應用

DI 容器中的 Logger 注入與測試

在實際應用中,Logger 通常透過 DI 容器注入。測試時需要適當設置:

public class OrderProcessingIntegrationTests
{
    private readonly ServiceProvider _serviceProvider;
    private readonly ITestOutputHelper _output;

    public OrderProcessingIntegrationTests(ITestOutputHelper output)
    {
        _output = output;
        
        var services = new ServiceCollection();
        
        // 設置測試用的 Logger
        services.AddLogging(builder =>
        {
            builder.AddProvider(new XUnitLoggerProvider(output));
        });
        
        // 註冊業務服務
        services.AddScoped<IOrderRepository, InMemoryOrderRepository>();
        services.AddScoped<IPaymentService, MockPaymentService>();
        services.AddScoped<OrderProcessor>();
        
        _serviceProvider = services.BuildServiceProvider();
    }

    [Fact]
    public async Task ProcessOrderAsync_完整訂單流程_應記錄所有步驟()
    {
        // Arrange
        using var scope = this._serviceProvider.CreateScope();
        var processor = scope.ServiceProvider.GetRequiredService<OrderProcessor>();

        var order = new Order
        {
            Id = $"ORDER-{Guid.NewGuid().ToString("N")[..8]}",
            CustomerId = "CUST001",
            Items =
            [
                new OrderItem { ProductId = "P001", ProductName = "測試商品", Quantity = 2, Price = 100 }
            ]
        };

        this._output.WriteLine("=== 測試訂單處理流程 ===");
        this._output.WriteLine($"訂單編號: {order.Id}");
        this._output.WriteLine($"客戶編號: {order.CustomerId}");

        // Act
        var result = await processor.ProcessOrderAsync(order);

        // Assert
        result.Should().NotBeNull();
        result.Success.Should().BeTrue();
        result.OrderId.Should().Be(order.Id);
        result.TotalAmount.Should().Be(200); // 2 * 100

        this._output.WriteLine("=== 測試完成 ===");
        this._output.WriteLine($"處理結果: {(result.Success ? "成功" : "失敗")}");
        this._output.WriteLine($"訂單金額: {result.TotalAmount:C}");

        // Logger 輸出會顯示在測試結果中,包含完整的處理流程
    }
}

測試執行輸出結果:

=== 測試訂單處理流程 ===
訂單編號: ORDER-c9a67618
客戶編號: CUST001
[11:15:02.774] [Information] [Day08.Core.Services.OrderProcessor] 開始非同步處理訂單 ORDER-c9a67618
[11:15:02.787] [Information] [Day08.Core.Tests.Integration.InMemoryOrderRepository] 儲存訂單 ORDER-c9a67618
[11:15:02.849] [Information] [Day08.Core.Tests.Integration.InMemoryOrderRepository] 訂單 ORDER-c9a67618 儲存成功
[11:15:02.850] [Information] [Day08.Core.Services.OrderProcessor] 訂單 ORDER-c9a67618 已儲存
[11:15:02.851] [Information] [Day08.Core.Tests.Integration.MockPaymentService] 處理付款,金額:$200
[11:15:02.851] [Information] [Day08.Core.Tests.Integration.MockPaymentService] 付款成功,交易編號:7ef2e914
[11:15:02.851] [Information] [Day08.Core.Services.OrderProcessor] 訂單 ORDER-c9a67618 處理完成
=== 測試完成 ===
處理結果: 成功
訂單金額: NT$200.00

記錄內容的斷言策略

針對結構化記錄進行精確斷言:

/// <summary>
/// 結構化記錄測試範例
/// </summary>
public class PaymentServiceTests
{
    [Fact]
    public void ProcessPayment_付款失敗交易_應記錄結構化資料()
    {
        // Arrange
        var paymentRequest = new PaymentRequest
        {
            Amount = 1000,
            Currency = "TWD",
            CardNumber = "****-****-****-1234"
        };

        var mockLogger = new TestLogger<PaymentService>();
        var service = new PaymentService(mockLogger);

        // Act
        var result = service.ProcessPayment(paymentRequest);

        // Assert
        result.Success.Should().BeFalse();

        // 驗證記錄內容
        var errorLogs = mockLogger.GetLogs(LogLevel.Error);
        errorLogs.Count.Should().Be(1);

        var errorLog = errorLogs[0];
        errorLog.Message.Should().Contain("Payment processing failed");
        errorLog.State.Should().ContainKey("Amount");
        errorLog.State.Should().NotContainKey("CardNumber"); // 確保敏感資料未記錄

        // 驗證敏感資料未被記錄
        errorLog.Message.Should().NotContain("1234");
    }
}

TestLogger - 測試用 Logger,支援記錄收集與驗證

public class TestLogger<T> : ILogger<T>
{
    private readonly List<LogEntry> _logs = [];

    public IDisposable BeginScope<TState>(TState state) where TState : notnull
    {
        return new NoOpDisposable();
    }

    public bool IsEnabled(LogLevel logLevel)
    {
        return true;
    }

    /// <summary>
    /// 記錄訊息
    /// </summary>
    /// <param name="logLevel">記錄層級</param>
    /// <param name="eventId">事件編號</param>
    /// <param name="state">狀態</param>
    /// <param name="exception">例外</param>
    /// <param name="formatter">格式化函數</param>
    /// <typeparam name="TState"></typeparam>
    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state,
                            Exception? exception, Func<TState, Exception?, string> formatter)
    {
        this._logs.Add(new LogEntry
        {
            Level = logLevel,
            Message = formatter(state, exception),
            State = state as IEnumerable<KeyValuePair<string, object>>,
            Exception = exception
        });
    }

    /// <summary>
    /// 取得記錄
    /// </summary>
    /// <param name="level">記錄層級</param>
    /// <returns></returns>
    public IList<LogEntry> GetLogs(LogLevel? level = null)
    {
        return level.HasValue ? this._logs.Where(l => l.Level == level).ToList() : this._logs.ToList();
    }

    /// <summary>
    /// 清除所有記錄
    /// </summary>
    public void ClearLogs()
    {
        this._logs.Clear();
    }
}

/// <summary>
/// 記錄項目
/// </summary>
public class LogEntry
{
    /// <summary>
    /// 記錄層級
    /// </summary>
    public LogLevel Level { get; set; }

    /// <summary>
    /// 記錄訊息
    /// </summary>
    public string Message { get; set; } = string.Empty;

    /// <summary>
    /// 記錄狀態
    /// </summary>
    public IEnumerable<KeyValuePair<string, object>>? State { get; set; }

    /// <summary>
    /// 例外資訊
    /// </summary>
    public Exception? Exception { get; set; }
}

非同步記錄的測試挑戰

非同步記錄需要特別的測試處理:

/// <summary>
/// 非同步記錄測試範例
/// </summary>
public class AsyncLoggingTests
{
    [Fact]
    public async Task ProcessAsync_非同步處理_應記錄開始和完成訊息()
    {
        // Arrange
        var mockLogger = new ConcurrentTestLogger<AsyncLoggingService>();
        var service = new AsyncLoggingService(mockLogger);

        // Act
        await service.ProcessAsync("test-data");

        // 等待背景記錄完成
        await Task.Delay(200);

        // Assert
        var logs = mockLogger.GetLogs();
        logs.Count.Should().BeGreaterThanOrEqualTo(1);
        logs.Should().Contain(l => l.Message.Contains("開始處理資料"));
        logs.Should().Contain(l => l.Message.Contains("資料處理完成"));`
    }
}

/// <summary>
/// class AsyncLoggingService - 非同步記錄服務(用於測試)
/// </summary>
public class AsyncLoggingService
{
    private readonly ILogger<AsyncLoggingService>? _logger;

    /// <summary>
    /// AsyncLoggingService 建構子
    /// </summary>
    /// <param name="logger">The logger.</param>
    public AsyncLoggingService(ILogger<AsyncLoggingService>? logger = null)
    {
        this._logger = logger;
    }

    /// <summary>
    /// 處理非同步資料
    /// </summary>
    /// <param name="data">要處理的資料</param>
    public async Task ProcessAsync(string data)
    {
        this._logger?.LogInformation("開始處理資料: {Data}", data);

        // 模擬非同步處理
        await Task.Delay(100);

        // 背景記錄
        _ = Task.Run(() => this._logger?.LogInformation("資料處理完成: {Data}", data));
    }
}

ConcurrentTestLogger - 並行測試用 Logger

public class ConcurrentTestLogger<T> : ILogger<T>
{
    private readonly ConcurrentBag<LogEntry> _logs = [];

    public IDisposable? BeginScope<TState>(TState state) where TState : notnull
    {
        return new NoOpDisposable();
    }

    public bool IsEnabled(LogLevel logLevel)
    {
        return true;
    }

    /// <summary>
    /// 記錄訊息
    /// </summary>
    /// <param name="logLevel">記錄層級</param>
    /// <param name="eventId">事件編號</param>
    /// <param name="state">狀態</param>
    /// <param name="exception">例外</param>
    /// <param name="formatter">格式化函數</param>
    /// <typeparam name="TState"></typeparam>
    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state,
                            Exception? exception, Func<TState, Exception?, string> formatter)
    {
        this._logs.Add(new LogEntry
        {
            Level = logLevel,
            Message = formatter(state, exception),
            State = state as IEnumerable<KeyValuePair<string, object>>,
            Exception = exception
        });
    }

    /// <summary>
    /// 取得記錄
    /// </summary>
    /// <param name="level">記錄層級</param>
    /// <returns></returns>
    public IList<LogEntry> GetLogs(LogLevel? level = null)
    {
        var allLogs = this._logs.ToList();
        return level.HasValue ? allLogs.Where(l => l.Level == level).ToList() : allLogs;
    }
}

診斷工具整合

為何需要 XUnitLogger 與 CompositeLogger

在實際測試中,我們經常面臨一個兩難問題:

  1. Mock Logger 驗證:我們需要驗證程式碼是否正確呼叫了記錄方法
  2. 測試診斷需求:當測試失敗時,我們希望在測試輸出中看到實際的記錄訊息

傳統的做法是二選一,但這兩個需求其實可以同時滿足。這就是為什麼我們需要建立 XUnitLogger 與 CompositeLogger 的原因。

問題背景

在 ASP.NET Core 的測試中,記錄訊息通常不會出現在測試輸出中,這使得除錯變得困難。同時,如果我們使用真實的 Logger,又無法進行行為驗證。

解決方案設計理念

  • XUnitLogger:將 ILogger 的訊息導向 xUnit 的測試輸出
  • CompositeLogger:組合多個 Logger,同時支援行為驗證與測試輸出

參考資料

這個解決方案參考了多個社群的最佳實踐:

  1. Unit-testing ILogger in ASP.NET Core

  2. 如何在單元測試中優雅地 Mock ILogger | Opass: A Life Well Lived

  3. How to get ASP.NET Core logs in the output of xUnit tests - Meziantou's blog

XUnitLogger 與 CompositeLogger 實作

當我們既要驗證記錄行為,又要在測試輸出中看到記錄訊息時,可以使用組合模式:

XUnitLogger 實作目的

XUnitLogger 的主要功能是將 ILogger 的輸出重新導向到 xUnit 的測試輸出中,讓我們在測試執行時能夠看到實際的記錄訊息。這在除錯複雜的業務邏輯時特別有用。

CompositeLogger 組合模式

CompositeLogger 採用組合設計模式,允許我們同時使用多個 Logger 實作。典型的使用場景是結合 Mock Logger(用於行為驗證)和 XUnit Logger(用於測試輸出診斷)。

public class XUnitLogger<T> : ILogger<T>
{
    private readonly ITestOutputHelper _testOutputHelper;
    private readonly string _categoryName;
    private readonly LoggerExternalScopeProvider _scopeProvider;

    public XUnitLogger(ITestOutputHelper testOutputHelper, LoggerExternalScopeProvider scopeProvider)
    {
        _testOutputHelper = testOutputHelper;
        _categoryName = typeof(T).Name;
        _scopeProvider = scopeProvider;
    }

    public bool IsEnabled(LogLevel logLevel) => logLevel != LogLevel.None;

    public IDisposable BeginScope<TState>(TState state) => _scopeProvider.Push(state);

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, 
        Exception exception, Func<TState, Exception, string> formatter)
    {
        var message = formatter(state, exception);
        var logLine = $"[{DateTime.Now:HH:mm:ss.fff}] [{logLevel}] [{_categoryName}] {message}";
        
        if (exception != null)
        {
            logLine += $"\n{exception}";
        }
        
        _testOutputHelper.WriteLine(logLine);
    }
}

public class CompositeLogger<T> : ILogger<T>
{
    private readonly ILogger<T>[] _loggers;

    public CompositeLogger(params ILogger<T>[] loggers)
    {
        _loggers = loggers;
    }

    public bool IsEnabled(LogLevel logLevel) 
        => _loggers.Any(logger => logger.IsEnabled(logLevel));

    public IDisposable BeginScope<TState>(TState state)
    {
        var scopes = _loggers.Select(logger => logger.BeginScope(state)).ToArray();
        return new CompositeDisposable(scopes);
    }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, 
        Exception exception, Func<TState, Exception, string> formatter)
    {
        foreach (var logger in _loggers)
        {
            logger.Log(logLevel, eventId, state, exception, formatter);
        }
    }
}

public class CompositeDisposable : IDisposable
{
    private readonly IDisposable[] _disposables;

    public CompositeDisposable(IDisposable[] disposables)
    {
        _disposables = disposables;
    }

    public void Dispose()
    {
        foreach (var disposable in _disposables)
        {
            disposable?.Dispose();
        }
    }
}

使用組合 Logger 進行測試:

public class OrderProcessingAdvancedTests
{
    private readonly AbstractLogger<OrderProcessingService> _mockLogger;
    private readonly ITestOutputHelper _output;
    private readonly ILogger<OrderProcessingService> _compositeLogger;
    
    public OrderProcessingAdvancedTests(ITestOutputHelper testOutputHelper)
    {
        this._output = testOutputHelper;
        this._mockLogger = Substitute.For<AbstractLogger<OrderProcessingService>>();

        var xunitLogger = new XUnitLogger<OrderProcessingService>(testOutputHelper, new LoggerExternalScopeProvider());
        this._compositeLogger = new CompositeLogger<OrderProcessingService>(this._mockLogger, xunitLogger);
    }

    [Fact]
    public void ProcessOrder_付款失敗_應記錄錯誤並輸出到測試結果()
    {
        // Arrange
        var inventoryService = Substitute.For<IInventoryService>();
        var paymentService = Substitute.For<IPaymentService>();

        var order = new Order
        {
            Id = "ORD004",
            ProductId = "PROD004",
            Quantity = 1,
            TotalAmount = 2000
        };

        inventoryService.CheckStock(order.ProductId, order.Quantity).Returns(true);
        paymentService.ProcessPayment(order.TotalAmount)
                      .Returns(new PaymentResult { Success = false, ErrorMessage = "餘額不足" });

        var sut = new OrderProcessingService(this._compositeLogger, inventoryService, paymentService);

        // Act
        var result = sut.ProcessOrder(order);

        // Assert
        result.Success.Should().BeFalse();

        // 驗證 Mock Logger(行為驗證)
        this._mockLogger.Received().Log(
            logLevel: LogLevel.Error,
            ex: null,
            information: Arg.Is<string>(msg => msg.Contains("付款失敗") && msg.Contains("ORD004")));

        // XUnit Logger 會自動將訊息輸出到測試結果中,方便除錯
        // 輸出格式:[HH:mm:ss.fff] [Error] [OrderProcessingService] 訂單 ORD004 付款失敗:餘額不足
    }
}

測試執行輸出結果:

[11:30:03.826] [Information] [OrderProcessingService] 開始處理訂單 ORD004 for customer 
[11:30:03.838] [Error] [OrderProcessingService] 訂單 ORD004 付款失敗:餘額不足

測試失敗時的快速問題定位

建立標準化的診斷輸出模式:

DiagnosticTestBase - 診斷測試基底類別

public class DiagnosticTestBase
{
    protected readonly ITestOutputHelper Output;

    protected DiagnosticTestBase(ITestOutputHelper output)
    {
        Output = output;
    }

    protected void LogTestContext(string testName, object testData = null)
    {
        Output.WriteLine($"=== {testName} ===");
        Output.WriteLine($"執行時間: {DateTime.Now:yyyy-MM-dd HH:mm:ss.fff}");
        
        if (testData != null)
        {
            Output.WriteLine($"測試資料: {JsonSerializer.Serialize(testData, new JsonSerializerOptions { WriteIndented = true })}");
        }
        
        Output.WriteLine("");
    }

    protected void LogException(Exception ex, string context = "")
    {
        Output.WriteLine($"=== 例外發生 {context} ===");
        Output.WriteLine($"例外類型: {ex.GetType().Name}");
        Output.WriteLine($"例外訊息: {ex.Message}");
        Output.WriteLine($"堆疊追蹤:\n{ex.StackTrace}");
        Output.WriteLine("");
    }

    protected void LogAssertionFailure(string expected, string actual, string fieldName)
    {
        Output.WriteLine($"=== 斷言失敗 ===");
        Output.WriteLine($"欄位: {fieldName}");
        Output.WriteLine($"預期值: {expected}");
        Output.WriteLine($"實際值: {actual}");
        Output.WriteLine("");
    }
}

ProductServiceDiagnosticTests - 商品服務診斷測試範例

public class ProductServiceDiagnosticTests : DiagnosticTestBase
{
    /// <summary>
    /// ProductServiceDiagnosticTests 建構子
    /// </summary>
    /// <param name="testOutputHelper">測試輸出協助器</param>
    /// <returns></returns>
    public ProductServiceDiagnosticTests(ITestOutputHelper testOutputHelper) : base(testOutputHelper)
    {
    }

    [Fact]
    public void CalculateTotalPrice_複雜折扣情境_應處理所有折扣計算()
    {
        try
        {
            // Arrange
            var testData = new
            {
                Customer = new { Type = "VIP", PurchaseHistory = 50000 },
                Items = new[]
                {
                    new { Name = "筆電", Price = 30000, Quantity = 1 },
                    new { Name = "滑鼠", Price = 1000, Quantity = 2 }
                },
                CouponCode = "SUMMER2024"
            };

            this.LogTestContext(nameof(this.CalculateTotalPrice_複雜折扣情境_應處理所有折扣計算), testData);

            var service = new ProductService();
            var customer = new Customer { Type = CustomerType.VIP, PurchaseHistory = 50000 };
            var items = new[]
            {
                new OrderItem { ProductName = "筆電", Price = 30000, Quantity = 1 },
                new OrderItem { ProductName = "滑鼠", Price = 1000, Quantity = 2 }
            };
            var couponCode = "SUMMER2024";

            // Act
            this.Output.WriteLine("開始執行價格計算...");
            var result = service.CalculateTotalPrice(customer, items, couponCode);
            this.Output.WriteLine($"計算結果: {result.TotalPrice:C}");

            // Assert
            var expectedPrice = 27200m; // 原價 32000 - VIP折扣 4800 - 優惠券折扣 3200 = 24000

            if (result.TotalPrice != expectedPrice)
            {
                this.LogAssertionFailure($"{expectedPrice:C}", $"{result.TotalPrice:C}", "TotalPrice");

                // 輸出詳細的計算過程
                this.Output.WriteLine("=== 計算明細 ===");
                this.Output.WriteLine($"原始金額: {result.OriginalAmount:C}");
                this.Output.WriteLine($"VIP 折扣: {result.VipDiscount:C}");
                this.Output.WriteLine($"優惠券折扣: {result.CouponDiscount:C}");
                this.Output.WriteLine($"最終金額: {result.TotalPrice:C}");
            }

            // 預期值:32000 - 4800 - 3200 = 24000
            result.TotalPrice.Should().Be(24000);
        }
        catch (Exception ex)
        {
            this.LogException(ex, "價格計算測試");
            throw;
        }
    }
}

測試執行輸出結果:

=== CalculateTotalPrice_複雜折扣情境_應處理所有折扣計算 ===
執行時間: 2025-08-17 11:32:46.332
測試資料: {
  "Customer": {
    "Type": "VIP",
    "PurchaseHistory": 50000
  },
  "Items": [
    {
      "Name": "\u7B46\u96FB",
      "Price": 30000,
      "Quantity": 1
    },
    {
      "Name": "\u6ED1\u9F20",
      "Price": 1000,
      "Quantity": 2
    }
  ],
  "CouponCode": "SUMMER2024"
}

開始執行價格計算...
計算結果: NT$24,000.00
=== 斷言失敗 ===
欄位: TotalPrice
預期值: NT$27,200.00
實際值: NT$24,000.00

=== 計算明細 ===
原始金額: NT$32,000.00
VIP 折扣: NT$4,800.00
優惠券折扣: NT$3,200.00
最終金額: NT$24,000.00

今日重點回顧

DO - 建議做法

  1. 適當使用 ITestOutputHelper

    • 在複雜測試中記錄重要步驟
    • 效能測試中記錄時間點
    • 測試失敗時提供診斷資訊
  2. Logger 測試策略

    • 使用抽象層簡化測試
    • 驗證重要的記錄行為
    • 結合 Mock 與實際輸出
  3. 結構化輸出

    • 採用一致的輸出格式
    • 包含時間戳記與分類
    • 提供足夠的上下文資訊

DON'T - 避免做法

  1. 不要過度使用輸出

    • 避免在每個測試中都大量輸出
    • 不要記錄過於細節的資訊
    • 避免影響測試執行效能
  2. 不要硬編碼記錄驗證

    • 避免驗證完整的記錄訊息
    • 不要依賴記錄訊息的確切格式
    • 避免測試內部實作細節
  3. 不要忽略生命週期

    • 不要在靜態方法中使用 ITestOutputHelper
    • 不要跨測試方法共用實例
    • 避免在非同步測試中遺漏等待

本日小結

測試輸出與記錄是提升測試品質和診斷效率的實用技術。今天我們探討了這些實用技術的應用方式:

ITestOutputHelper 核心技術

  • 正確的注入方式:透過建構式注入 ITestOutputHelper,避免靜態存取陷阱
  • 生命週期管理:理解每個測試方法都有獨立的實例,不可跨測試方法共用
  • 結構化輸出設計:建立一致的輸出格式,包含章節標題、時間戳記與分類資訊
  • 效能測試整合:在效能測試中記錄重要時間點,提供詳細的執行軌跡

ILogger 測試策略與挑戰

  • 擴充方法的測試限制:LogError 等擴充方法無法直接 Mock,需要攔截底層 Log 方法
  • AbstractLogger 抽象層:建立簡化的抽象層,避免複雜的泛型方法驗證
  • 行為驗證技巧:掌握記錄層級、訊息內容與呼叫次數的驗證方法
  • 結構化記錄測試:驗證記錄內容的同時確保敏感資料不被記錄

進階診斷工具整合

  • CompositeLogger 模式:同時支援行為驗證與測試輸出的組合設計
  • XUnitLogger 實作:將 ILogger 訊息導向測試輸出,提升除錯效率
  • DI 容器整合:在整合測試中正確設置 Logger 提供者
  • 非同步記錄處理:使用 ConcurrentTestLogger 處理背景記錄的測試挑戰

實務應用建議

  • 測試診斷標準化:建立統一的診斷輸出模式,包含測試資料、例外資訊與斷言失敗詳情
  • 問題定位技巧:透過結構化輸出快速識別測試失敗的根本原因
  • 最佳實踐平衡:在測試效率與診斷能力之間找到適當平衡點

這些技術讓我們的測試不再是黑盒子,而是具備可觀測性的診斷工具,有效提升除錯效率與開發信心。

明天我們將瞭解單元測試對於 Private 與 Internal 的測試策略。

範例程式碼:


這是「重啟挑戰:老派軟體工程師的測試修練」的第八天。明天會介紹 Day 09:測試私有與內部成員 - Private 與 Internal 的測試策略。


上一篇
Day 07:依賴替代入門 - 使用 NSubstitute
下一篇
Day 09:測試私有與內部成員 - Private 與 Internal 的測試策略
系列文
重啟挑戰:老派軟體工程師的測試修練24
圖片
  熱門推薦
圖片
{{ item.channelVendor }} | {{ item.webinarstarted }} |
{{ formatDate(item.duration) }}
直播中

尚未有邦友留言

立即登入留言